search

FreeTDS / freetds

Official FreeTDS repository
http://www.freetds.org/
GNU General Public License v2.0
459 stars 156 forks source link

util.c:83:logic error: cannot change query state from IDLE to PENDING #416

Open dadamssg opened 3 years ago

dadamssg commented 3 years ago

I'm using rsyslog to push nginx logs to sql server using freetds but it just stopped working. I had it working at one point and then without doing anything it seems to have gotten itself into a broken state, of which i cannot get it out of.

I'm just now learning about rsyslog and freetds so i'm not sure what i need to do. I see this when i tail the freetds log. 

token.c:553:tds_process_tokens(0x7ff9b0002ba0, 0x7ff9bebfab00, 0x7ff9bebfab04, 0x6914)
util.c:165:Changed query state from PENDING to READING
token.c:568:processing result tokens.  marker is  fe(DONEPROC)
token.c:2094:tds_process_end: more_results = 0
                was_cancelled = 0
                error = 0
                done_count_valid = 0
token.c:2113:                rows_affected = 0
token.c:2116:tds_process_end() state set to TDS_IDLE
util.c:165:Changed query state from READING to IDLE
util.c:83:logic error: cannot change query state from IDLE to PENDING
util.c:165:Changed query state from IDLE to IDLE
ct.c:1235:ct_results() process_result_tokens returned 0 (type 4053) 
ct.c:1171:ct_results(0x7ff9b0002740, 0x7ff9bebfab84)
ct.c:1171:ct_results(0x7ff9b0002740, 0x7ff9bebfab84)
token.c:553:tds_process_tokens(0x7ff9b0002ba0, 0x7ff9bebfab00, 0x7ff9bebfab04, 0x6914)
token.c:556:tds_process_tokens() state is COMPLETED
ct.c:1235:ct_results() process_result_tokens returned 1 (type 4052) 
ct.c:236:ct_describe_cmd_state(3)
ct.c:236:ct_describe_cmd_state(2)
ct.c:224:setting command state to READY (from SENT)

I suspect the following line is a clue:

util.c:83:logic error: cannot change query state from IDLE to PENDING

I don't know what to do from here though. i don't know if this is a user error or if i found a bug.

I'm on centos 7 with the following installed libdbi-drivers-0.8.3-16.el7.x86_64

KarimElsayad247 commented 1 year ago

Having a similar problem with a rails, tinytds, freetds setup, with ms sql server running in a docker container.

logs:

dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:3379:dbcancel(0x7f654669d920)
query.c:2128:tds_send_cancel: not in_cancel and idle
dblib.c:1359:dbcmd(0x7f654669d920, SELECT [cities].* FROM [cities] ORDER BY name_ar ASC)
dblib.c:1365:dbcmd() bufsz = 313
dblib.c:6043:dbfreebuf(0x7f654669d920)
dblib.c:7033:dbsqlsend(0x7f654669d920)
mem.c:656:tds_free_all_results()
util.c:165:Changed query state from IDLE to WRITING
util.c:165:Changed query state from WRITING to PENDING
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:4801:dbsqlok(0x7f654669d920)
dblib.c:4830:dbsqlok() not done, calling tds_process_tokens()
token.c:553:tds_process_tokens(0x7f654556b5c0, 0x7f65648bbe08, 0x7f65648bbe0c, 0x6914)
util.c:165:Changed query state from PENDING to READING
dbutil.c:202:_dblib_check_and_handle_interrupt 0x7f654669d920 [0x7f65670187b0, 0x7f6567018790]
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dbutil.c:202:_dblib_check_and_handle_interrupt 0x7f654669d920 [0x7f65670187b0, 0x7f6567018790]
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dbutil.c:202:_dblib_check_and_handle_interrupt 0x7f654669d920 [0x7f65670187b0, 0x7f6567018790]
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dbutil.c:202:_dblib_check_and_handle_interrupt 0x7f654669d920 [0x7f65670187b0, 0x7f6567018790]
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dbutil.c:202:_dblib_check_and_handle_interrupt 0x7f654669d920 [0x7f65670187b0, 0x7f6567018790]
dblib.c:5941:dbgetuserdata(0x7f654669d920)
util.c:319:tdserror(0x7f6544cd7b60, 0x7f654556b5c0, 20003, 0)
dblib.c:8122:dbperror(0x7f654669d920, 20003, 0)
dblib.c:8190:dbperror: Calling dblib_err_handler with msgno = 20003; msg->msgtext = "Adaptive Server connection timed out"
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:5041:dbdead(0x7f654669d920) [alive]
dblib.c:3379:dbcancel(0x7f654669d920)
query.c:2128:tds_send_cancel: not in_cancel and not idle
dblib.c:8212:dbperror: dblib_err_handler for msgno = 20003; msg->msgtext = "Adaptive Server connection timed out" -- returns 3 (INT_TIMEOUT)
util.c:349:tdserror: client library returned TDS_INT_TIMEOUT(3)
query.c:2128:tds_send_cancel: in_cancel and not idle
util.c:372:tdserror: returning TDS_INT_CONTINUE(1)
token.c:568:processing result tokens.  marker is  81(TDS7_RESULT)
token.c:1572:processing TDS7 result metadata.
mem.c:656:tds_free_all_results()
token.c:1597:set current_results (5 columns) to tds->res_info
token.c:1604:setting up 5 columns
token.c:1541:tds7_get_data_info: 
    colname = id
    type = 127 (bigint)
    server's type = 127 (bigint)
    column_varint_size = 0
    column_size = 8 (8 on server)
token.c:3257:adjust_character_column_size:
    Server charset: UTF-16LE
    Server column_size: 8000
    Client charset: UTF-8
    Client column_size: 16000
token.c:1541:tds7_get_data_info: 
    colname = name_ar
    type = 39 (varchar)
    server's type = 231 (x UCS-2 varchar)
    column_varint_size = 2
    column_size = 16000 (8000 on server)
token.c:3257:adjust_character_column_size:
    Server charset: UTF-16LE
    Server column_size: 8000
    Client charset: UTF-8
    Client column_size: 16000
token.c:1541:tds7_get_data_info: 
    colname = name_en
    type = 39 (varchar)
    server's type = 231 (x UCS-2 varchar)
    column_varint_size = 2
    column_size = 16000 (8000 on server)
token.c:1541:tds7_get_data_info: 
    colname = created_at
    type = 61 (datetime)
    server's type = 61 (datetime)
    column_varint_size = 0
    column_size = 8 (8 on server)
token.c:1541:tds7_get_data_info: 
    colname = updated_at
    type = 61 (datetime)
    server's type = 61 (datetime)
    column_varint_size = 0
    column_size = 8 (8 on server)
token.c:1613: name                 size/wsize      type/wtype      utype  
token.c:1614: -------------------- --------------- --------------- -------
token.c:1619: id                         8/8           127/127           0
token.c:1619: name_ar                16000/8000         39/231           0
token.c:1619: name_en                16000/8000         39/231           0
token.c:1619: created_at                 8/8            61/61            0
token.c:1619: updated_at                 8/8            61/61            0
token.c:568:processing result tokens.  marker is  a9(ORDERBY)
token.c:129:tds_process_default_tokens() marker is a9(ORDERBY)
token.c:248:Eating ORDERBY token
token.c:568:processing result tokens.  marker is  fd(DONE)
token.c:2094:tds_process_end: more_results = 0
        was_cancelled = 0
        error = 1
        done_count_valid = 0
token.c:2113:                rows_affected = 0
token.c:568:processing result tokens.  marker is  fd(DONE)
token.c:2094:tds_process_end: more_results = 0
        was_cancelled = 1
        error = 0
        done_count_valid = 0
token.c:2113:                rows_affected = 0
token.c:2116:tds_process_end() state set to TDS_IDLE
util.c:165:Changed query state from READING to IDLE
util.c:83:logic error: cannot change query state from IDLE to PENDING
util.c:165:Changed query state from IDLE to IDLE
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:5941:dbgetuserdata(0x7f654669d920)
dblib.c:5041:dbdead(0x7f654669d920) [alive]
dblib.c:4801:dbsqlok(0x7f654669d920)
dblib.c:4830:dbsqlok() not done, calling tds_process_tokens()
token.c:553:tds_process_tokens(0x7f654556b5c0, 0x7f65648ba5b8, 0x7f65648ba5bc, 0x6914)
token.c:556:tds_process_tokens() state is COMPLETED
dblib.c:3379:dbcancel(0x7f654669d920)
query.c:2128:tds_send_cancel: not in_cancel and idle
dblib.c:5941:dbgetuserdata(0x7f654669d920)
freddy77 commented 1 year ago

That warning is usually not an issue. Do you have a practical problem?

On Mon, 15 May 2023, 17:51 Karim M. Elsayad, @.***> wrote:

Having a similar problem with a rails, tinytds, freetds setup, with ms sql server running in a docker container.

logs:

dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:3379:dbcancel(0x7f654669d920) query.c:2128:tds_send_cancel: not in_cancel and idle dblib.c:1359:dbcmd(0x7f654669d920, SELECT [cities].* FROM [cities] ORDER BY name_ar ASC) dblib.c:1365:dbcmd() bufsz = 313 dblib.c:6043:dbfreebuf(0x7f654669d920) dblib.c:7033:dbsqlsend(0x7f654669d920) mem.c:656:tds_free_all_results() util.c:165:Changed query state from IDLE to WRITING util.c:165:Changed query state from WRITING to PENDING dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:4801:dbsqlok(0x7f654669d920) dblib.c:4830:dbsqlok() not done, calling tds_process_tokens() token.c:553:tds_process_tokens(0x7f654556b5c0, 0x7f65648bbe08, 0x7f65648bbe0c, 0x6914) util.c:165:Changed query state from PENDING to READING dbutil.c:202:_dblib_check_and_handle_interrupt 0x7f654669d920 [0x7f65670187b0, 0x7f6567018790] dblib.c:5941:dbgetuserdata(0x7f654669d920) dbutil.c:202:_dblib_check_and_handle_interrupt 0x7f654669d920 [0x7f65670187b0, 0x7f6567018790] dblib.c:5941:dbgetuserdata(0x7f654669d920) dbutil.c:202:_dblib_check_and_handle_interrupt 0x7f654669d920 [0x7f65670187b0, 0x7f6567018790] dblib.c:5941:dbgetuserdata(0x7f654669d920) dbutil.c:202:_dblib_check_and_handle_interrupt 0x7f654669d920 [0x7f65670187b0, 0x7f6567018790] dblib.c:5941:dbgetuserdata(0x7f654669d920) dbutil.c:202:_dblib_check_and_handle_interrupt 0x7f654669d920 [0x7f65670187b0, 0x7f6567018790] dblib.c:5941:dbgetuserdata(0x7f654669d920) util.c:319:tdserror(0x7f6544cd7b60, 0x7f654556b5c0, 20003, 0) dblib.c:8122:dbperror(0x7f654669d920, 20003, 0) dblib.c:8190:dbperror: Calling dblib_err_handler with msgno = 20003; msg->msgtext = "Adaptive Server connection timed out" dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:5041:dbdead(0x7f654669d920) [alive] dblib.c:3379:dbcancel(0x7f654669d920) query.c:2128:tds_send_cancel: not in_cancel and not idle dblib.c:8212:dbperror: dblib_err_handler for msgno = 20003; msg->msgtext = "Adaptive Server connection timed out" -- returns 3 (INT_TIMEOUT) util.c:349:tdserror: client library returned TDS_INT_TIMEOUT(3) query.c:2128:tds_send_cancel: in_cancel and not idle util.c:372:tdserror: returning TDS_INT_CONTINUE(1) token.c:568:processing result tokens. marker is 81(TDS7_RESULT) token.c:1572:processing TDS7 result metadata. mem.c:656:tds_free_all_results() token.c:1597:set current_results (5 columns) to tds->res_info token.c:1604:setting up 5 columns token.c:1541:tds7_get_data_info: colname = id type = 127 (bigint) server's type = 127 (bigint) column_varint_size = 0 column_size = 8 (8 on server) token.c:3257:adjust_character_column_size: Server charset: UTF-16LE Server column_size: 8000 Client charset: UTF-8 Client column_size: 16000 token.c:1541:tds7_get_data_info: colname = name_ar type = 39 (varchar) server's type = 231 (x UCS-2 varchar) column_varint_size = 2 column_size = 16000 (8000 on server) token.c:3257:adjust_character_column_size: Server charset: UTF-16LE Server column_size: 8000 Client charset: UTF-8 Client column_size: 16000 token.c:1541:tds7_get_data_info: colname = name_en type = 39 (varchar) server's type = 231 (x UCS-2 varchar) column_varint_size = 2 column_size = 16000 (8000 on server) token.c:1541:tds7_get_data_info: colname = created_at type = 61 (datetime) server's type = 61 (datetime) column_varint_size = 0 column_size = 8 (8 on server) token.c:1541:tds7_get_data_info: colname = updated_at type = 61 (datetime) server's type = 61 (datetime) column_varint_size = 0 column_size = 8 (8 on server) token.c:1613: name size/wsize type/wtype utype token.c:1614: -------------------- --------------- --------------- ------- token.c:1619: id 8/8 127/127 0 token.c:1619: name_ar 16000/8000 39/231 0 token.c:1619: name_en 16000/8000 39/231 0 token.c:1619: created_at 8/8 61/61 0 token.c:1619: updated_at 8/8 61/61 0 token.c:568:processing result tokens. marker is a9(ORDERBY) token.c:129:tds_process_default_tokens() marker is a9(ORDERBY) token.c:248:Eating ORDERBY token token.c:568:processing result tokens. marker is fd(DONE) token.c:2094:tds_process_end: more_results = 0 was_cancelled = 0 error = 1 done_count_valid = 0 token.c:2113: rows_affected = 0 token.c:568:processing result tokens. marker is fd(DONE) token.c:2094:tds_process_end: more_results = 0 was_cancelled = 1 error = 0 done_count_valid = 0 token.c:2113: rows_affected = 0 token.c:2116:tds_process_end() state set to TDS_IDLE util.c:165:Changed query state from READING to IDLE util.c:83:logic error: cannot change query state from IDLE to PENDING util.c:165:Changed query state from IDLE to IDLE dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:5941:dbgetuserdata(0x7f654669d920) dblib.c:5041:dbdead(0x7f654669d920) [alive] dblib.c:4801:dbsqlok(0x7f654669d920) dblib.c:4830:dbsqlok() not done, calling tds_process_tokens() token.c:553:tds_process_tokens(0x7f654556b5c0, 0x7f65648ba5b8, 0x7f65648ba5bc, 0x6914) token.c:556:tds_process_tokens() state is COMPLETED dblib.c:3379:dbcancel(0x7f654669d920) query.c:2128:tds_send_cancel: not in_cancel and idle dblib.c:5941:dbgetuserdata(0x7f654669d920)

— Reply to this email directly, view it on GitHub https://github.com/FreeTDS/freetds/issues/416#issuecomment-1548208251, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAHWP2CPSA6KOO4C6NGNCQ3XGJNJVANCNFSM5C4ECMGQ . You are receiving this because you are subscribed to this thread.Message ID: @.***>

KarimElsayad247 commented 1 year ago

@freddy77

I'm having this issue (seen in logs above) 

dblib.c:8212:dbperror: dblib_err_handler for msgno = 20003; msg->msgtext = "Adaptive Server connection timed out" -- returns 3 (INT_TIMEOUT)
freddy77 commented 1 year ago

It looks like a timeout, that is the server is not communicating in the expected time