Splunk DB Connect - Failed attempting to parse transport header

[michaelhc]

Hi,

I am attempting to use dbxquery to fetch and transform the results of an extended events session from MSSQL Server 2016 which has been saved to a file. I have three saved searches which follow the same format, two of which work and one which doesn't, and behaves quite peculiarly. When I attempt to run the query below, I get a ChunkedExternProcessor error: 

07-28-2020 23:32:01.824 ERROR ChunkedExternProcessor - Failed attempting to parse transport header: ,,,,,,,,,,\r\r
07-28-2020 23:32:01.924 ERROR ChunkedExternProcessor - Error in 'dbxquery' command: Invalid message received from external search command during search, see search.log.

| dbxquery query="SELECT event_data = CONVERT(XML, event_data)
 INTO #<TempTableName> FROM sys.fn_xe_file_target_read_file('<PathToLogFile>/LogFile*',null,null,null)
 SELECT name = event_data.value(N'(event/@name)[1]', N'varchar(max)'),
 errorNumber = event_data.value(N'(event/data[@name="error_number"]/value)[1]', N'varchar(max)'),
 severity = event_data.value(N'(event/data[@name="severity"]/value)[1]', N'varchar(max)'),
 message = event_data.value(N'(event/data[@name="message"]/value)[1]', N'varchar(max)'),
 hostname = event_data.value(N'(event/action[@name="client_hostname"]/value)[1]', N'varchar(max)'),
 username = event_data.value(N'(event/action[@name="username"]/value)[1]', N'varchar(max)'),
 [sql] = event_data.value(N'(event/action[@name="sql_text"]/value)[1]', N'varchar(max)'),
 session_id = event_data.value(N'(event/action[@name="session_id"]/value)[1]', N'varchar(max)'),
 query_hash = event_data.value(N'(event/action[@name="query_hash"]/value)[1]', N'varchar(max)'),
 database_id = event_data.value(N'(event/action[@name="database_id"]/value)[1]', N'varchar(max)'),
 client_app_name = event_data.value(N'(event/action[@name="client_app_name"]/value)[1]', N'varchar(max)')
 FROM #<TempTableName>" connection="<My connection name>"

I am confused why my other queries, which follow this same format work, yet this one returns this error. If I reduce the number of fields to just 'name', the error changes to one of two possibilites:

07-28-2020 23:36:16.429 ERROR ChunkedExternProcessor - stderr: Traceback (most recent call last):
07-28-2020 23:36:16.429 ERROR ChunkedExternProcessor - stderr:   File "C:\Program Files\Splunk\etc\apps\splunk_app_db_connect\bin\dbxquery_bridge.py", line 90, in <module>
07-28-2020 23:36:16.429 ERROR ChunkedExternProcessor - stderr:     main()
07-28-2020 23:36:16.429 ERROR ChunkedExternProcessor - stderr:   File "C:\Program Files\Splunk\etc\apps\splunk_app_db_connect\bin\dbxquery_bridge.py", line 86, in main
07-28-2020 23:36:16.429 ERROR ChunkedExternProcessor - stderr:     bridge.connect()
07-28-2020 23:36:16.429 ERROR ChunkedExternProcessor - stderr:   File "C:\Program Files\Splunk\etc\apps\splunk_app_db_connect\bin\dbxquery_bridge.py", line 38, in connect
07-28-2020 23:36:16.429 ERROR ChunkedExternProcessor - stderr:     self.read_from_dbxquery_server_write_to_stdout()
07-28-2020 23:36:16.429 ERROR ChunkedExternProcessor - stderr:   File "C:\Program Files\Splunk\etc\apps\splunk_app_db_connect\bin\dbxquery_bridge.py", line 74, in read_from_dbxquery_server_write_to_stdout
07-28-2020 23:36:16.429 ERROR ChunkedExternProcessor - stderr:     data = recv(1024 * 1024)
07-28-2020 23:36:16.429 ERROR ChunkedExternProcessor - stderr: ConnectionAbortedError: [WinError 10053] An established connection was aborted by the software in your host machine

or,

07-28-2020 23:37:45.389 ERROR ChunkedExternProcessor - Failed attempting to parse transport header: eported,\r\r
07-28-2020 23:37:45.490 ERROR ChunkedExternProcessor - Error in 'dbxquery' command: Invalid message received from external search command during search, see search.log. 

 The name field should read "error reported" so the 'eported' implies some information is being missed, and the connection is being closed too early, but I am not sure why this would occur.

Any ideas? Thanks

[chli_splunk]

Basically this error is about the chunk processor, which is the communication protocol between DBX and search app. Since you mentioned other searches work well, I guess the root cause is about the column names: either some special characters, or non-utf8 chars. Most likely it's the later.

May I ask your DBX version? We fixed a bug of  DBX 3.3.1 about the utf8 support. 

[michaelhc]

Thanks for the response.

We were on 3.3.0 so I've just updated our setup to 3.3.1 which has changed a few things:

Now when I run the large query with no filtering I receive the name and ts columns completely filled, but the rest are empty and there are no errors in search.log. When I append "WHERE event_data.value(N'(event/@timestamp)[1]', N'datetime') < GETDATE() AND event_data.value(N'(event/@timestamp)[1]', N'datetime') > DATEADD(minute,-60,GETDATE())"  to the query I get "No results found. Try expanding the time range." and looking at search.log shows the connection aborted error. I have confirmed that this query works on SQL Server Management Studio with and without the time filtering. One thing I tried was creating a stored procedure using the query that works within Management Studio, then using dbxquery to execute that stored procedure, but I still get the same "No results found" output with the connection aborted error. 

I noticed that when I wasn't filtering by time, the query would return exactly 100,000 results, with the timestamp of the latest being a couple of days ago. I figured this must be why filtering by time wasn't working and thought maybe the extended events file size was causing issues, so I adjusted the max file size and started a new session. This allowed me to run a query with time filtering, which returned less than 100,000 results as expected, but still only had the name and ts fields filled and the connection aborted error in search.log.

Is the bug fix you're referring to available in the latest download? If so it unfortunately doesn't seem to have resolved my issue. 

Out of desperation I tried calling the stored procedure again and weirdly enough that now seems to work and returns all columns complete. The plot thickens...

[chli_splunk]

I fixed a bug about "carriage return" on Windows, which corrupts the chunk buffer. I guess it's related. Please try DBX 3.3.1, or insert following codes to {DBConnect}/bin/dbxquery_bridge.py: added Python3 support.

    def read_from_dbxquery_server_write_to_stdout(self):
        # DBX-4889, in windows, text mode stdout write will generate one more
        # carrige return '\r' which corrupts the data.
        if sys.platform == "win32":
            if sys.version_info[0] < 3: # Python 2
                import os
                import msvcrt
                msvcrt.setmode(sys.stdout.fileno(), os.O_BINARY)
            else: # Python 3
                sys.stdout = stdout = open(sys.__stdout__.fileno(), 
                                            mode=sys.__stdout__.mode, 
                                            buffering=1, 
                                            encoding=sys.__stdout__.encoding, 
                                            errors=sys.__stdout__.errors, 
                                            newline='\n', 
                                            closefd=False)

[richgalloway]

Have you contacted your DBA to find out what errors are reported by the DB server?